ASoC: SOF: ipc4-mtrace: resync host_read_ptr on debugfs open and release#5690
ASoC: SOF: ipc4-mtrace: resync host_read_ptr on debugfs open and release#5690majunkier wants to merge 1 commit intothesofproject:topic/sof-devfrom
Conversation
IPC4 mtrace debugfs read handler advances host_read_ptr in SRAM after consuming all available data. When file descriptor is closed, host_read_ptr is left equal to dsp_write_ptr in kernel core_data cache. So subsequent open() inherits this stale pointer. first read() call, sof_wait_mtrace_avail() find host_read_ptr == dsp_write_ptr and block waiting for NOTIFY_LOG_BUFFER_STATUS IPC from fw. Platforms with low post-boot DSP activity timer (256 ms) may not work good with reader timeout window, resulting in empty trace output. Fix this by re-reading dsp_write_ptr directly from SRAM in open() and aligning host_read_ptr to it, so new reader starts from current write position without waiting for IPC notification. Also reset host_read_ptr to dsp_write_ptr in release() to leave core_data to consistent state. Reset target is dsp_write_ptr (not 0) to avoid re-reading stale data that may remain before last wrap of circular buffer. Signed-off-by: Mateusz Junkier <mateusz.junkier@intel.com>
majunkier
requested review from
bardliao,
dbaluta,
kv2019i,
lgirdwood,
plbossart,
ranj063 and
ujfalusi
as code owners
| &write_ptr, sizeof(write_ptr)); | ||
| write_ptr -= write_ptr % 4; | ||
| core_data->dsp_write_ptr = write_ptr; | ||
| core_data->host_read_ptr = write_ptr; |
There was a problem hiding this comment.
but you will loose debug data between two opens?
open / read / close
fw still prints # this information might be lost?
open / read /close
There was a problem hiding this comment.
Ack @ujfalusi , I asked @majunkier to push this for review. THis is genuine problem, but not sure which way to go about. The current implementation is intentional in the sense that you cannot run mtrace-reader.py before the driver is loaded, and as the driver loads and boots the DSP, it is not possible to get first boot logs if the read pointer is reset at boot. IOW, ability to get old logs is a feature. But as Mateusz has rootcaused, this creates non-deterministic behaviour is the mtrace-reader is restarted, and this is showing up as problems in some scenarios we have in CI. It's also true mtrace-reader.py needs to be stopped before the driver can be unloaded.
Not sure how to best solve this. I don't think we sync at open. Sync at close is a possibility, but this is still not deterministic. I guess one option is to just document this behaviour and the test case (that checks whether logging is working) needs to create some DSP activity that ensures there is new logs after mtrace-reader is restarted. Ideas are welcome!
There was a problem hiding this comment.
I'm not sure, but have we tried to read the pointers directly from the slot?
I guess the issue shows up when the DSP is suspended and the the write counter got reset (also the read ptr in slot).
If we read the write/read ptr from slot on open then we will have up-to date info, or we just always read them on every time in sof_ipc4_mtrace_dfs_read(), first I would try the sync at open only. There is a reason why we only update the write ptr when fw tells that it has moved.
| * dsp_write_ptr (not 0) avoids re-reading stale data from | ||
| * wrapped circular buffer. | ||
| */ | ||
| core_data->host_read_ptr = core_data->dsp_write_ptr; |
There was a problem hiding this comment.
either of the two change is redundant? If you reset the pointers in open then this is not needed, but resetting might be a problem as well.
3 participants
IPC4 mtrace debugfs read handler advances host_read_ptr in SRAM after consuming all available data. When file descriptor is closed, host_read_ptr is left equal to dsp_write_ptr in kernel core_data cache. So subsequent open() inherits this stale pointer. first read() call, sof_wait_mtrace_avail() find host_read_ptr == dsp_write_ptr and block waiting for NOTIFY_LOG_BUFFER_STATUS IPC from fw. Platforms with low post-boot DSP activity timer (256 ms) may not work good with reader timeout window, resulting in empty trace output.
Fix this by re-reading dsp_write_ptr directly from SRAM in open() and aligning host_read_ptr to it, so new reader starts from current write position without waiting for IPC notification. Also reset host_read_ptr to dsp_write_ptr in release() to leave core_data to consistent state.
Reset target is dsp_write_ptr (not 0) to avoid re-reading stale data that may remain before last wrap of circular buffer.